Pythonのline_profilerを使って、関数の実行時間を計測してみた

#Python

横山文人

2015.08.06

この記事は公開されてから1年以上経過しています。情報が古い可能性がありますので、ご注意ください。

サーモン大好き横山です。

Pythonのコードを書いていて、どの処理で遅延しているか調べるとき、どうしていますか？

今回は関数の行ごとに実行速度を計測出来る line_profiler を紹介します。

準備

今回はMac上でやっていきます。

$ sw_vers
ProductName:    Mac OS X
ProductVersion: 10.10.4
BuildVersion:   14E46

$ python -V
Python 2.7.9

環境はPython2.7でvirtualenvの準備をします。

$ mkdir -p /tmp/line_profiler
$ cd !:2
cd /tmp/line_profiler

$ virtualenv -p /usr/bin/python2.7 venv27
Running virtualenv with interpreter /usr/bin/python2.7
New python executable in venv27/bin/python
Installing setuptools, pip...done.

$ . venv27/bin/activate
(venv27)$ pip install -U pip
(venv27)$ pip install line_profiler

解析するコード

今回は、実行時遅くなるところを time.sleep を使い表現します。

#/usr/bin/env python
from __future__ import print_function
import time

def main():
    for i in range(10):
        print('sleep 0.2')
        time.sleep(0.2)

        print('sleep 0.3')
        time.sleep(0.3)

        print('sleep 0.5')
        time.sleep(0.5)

        print('sleep 0.7')
        time.sleep(0.7)

if __name__ == '__main__':
    main()

解析

解析用に demo.py をコピーします。コピーする理由は後で後述します。

(venv27)$ cp demo{,_analyze}.py

demo_analyze.pyに@profile のデコレータを追加します。

#/usr/bin/env python
from __future__ import print_function
import time

@profile
def main():
    for i in range(10):
        print('sleep 0.2')
        time.sleep(0.2)

        print('sleep 0.3')
        time.sleep(0.3)

        print('sleep 0.5')
        time.sleep(0.5)

        print('sleep 0.7')
        time.sleep(0.7)

if __name__ == '__main__':
    main()

line_profiler をインストールした時に追加される、 kernprof コマンドを実行します。

(venv27)$ kernprof -l demo_analyze.py
sleep 0.2
sleep 0.3
sleep 0.5
sleep 0.7

... (省略) ...

sleep 0.2
sleep 0.3
sleep 0.5
sleep 0.7

kernprof: command not found と怒られましたら、一度virtualenvの環境から抜け、
再度環境に入ってコマンドの有無を確認してみてください。

(venv27)$ deactivate
$ . venv27/bin/activate

コマンド実行後、 demo_analyze.py.lprof というファイルができていると思います。次に、 python -m line_profiler demo_analyze.py.lprof を実行します。

(venv27)$ python -m line_profiler demo_analyze.py.lprof
Timer unit: 1e-06 s

Total time: 17.1318 s
File: demo_analyze.py
Function: main at line 5

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
     5                                           @profile
     6                                           def main():
     7        11          159     14.5      0.0      for i in range(10):
     8        10          538     53.8      0.0          print('sleep 0.2')
     9        10      2028254 202825.4     11.8          time.sleep(0.2)
    10
    11        10          646     64.6      0.0          print('sleep 0.3')
    12        10      3036386 303638.6     17.7          time.sleep(0.3)
    13
    14        10          595     59.5      0.0          print('sleep 0.5')
    15        10      5031002 503100.2     29.4          time.sleep(0.5)
    16
    17        10          634     63.4      0.0          print('sleep 0.7')
    18        10      7033621 703362.1     41.1          time.sleep(0.7)

実行しますと上記の様な実行結果が表示されると思います。下部に表示されている表の1行を抜き出しますと、以下のように表示されます。

     9        10      2028254 202825.4     11.8          time.sleep(0.2)

左から、
行番号、実行回数、トータル実行時間(ナノ秒)、1回あたりの実行時間(ナノ秒)、関数内での実行時間の割合（％）、実行したコード行
となっております。

この表示を参考にどこが処理のネックになっているか、簡単に確認することが出来ます。

なぜプログラムコピーをしたのか。

デコレータ、 @profile つけた後通常実行しようとすると実行出来ないためです。今回はデコレータを削除する手間を省くためコードをコピーし、コピーした側に、 @profile をつけて実行しました。こちらは、デコレータを削除する手間を惜しまないのであればコピーしなくても実行することが可能です。

因みにつけたまま実行しようしますと以下のようになります。

(venv27)$ python demo_analyze.py
Traceback (most recent call last):
  File "demo_analyze.py", line 5, in <module>
    @profile
NameError: name 'profile' is not defined